压力测试之路

1.盲人摸象–tsung

测试目的：找出play的最大负载能力，进而找出性能瓶颈

tsung测试环境

说明

• 上述配置得到的最大并发数应该是200 * 300 = 60000
• tsung每10秒统计一次

tusng 产生的用户数

每秒响应数

最大并发请求数达到了6000次每秒，260s以后，曲线走势很乱，后来总结出来当并发请求数波动幅度很大时应该是远远超出了此api的承受能力，但这是否可以说这个api的最大负载能力是6000次每秒？这还要结合响应时间图

响应时间

响应时间在260s之前，大部分都在1s以内，260s之后，急剧攀升，最大达到了12s，此时的并发请求数约为50000，而响应数仅有每秒5000个，若以响应时间小于1s为标准，那么这个api的最大负载能力应该是在5000。每秒5000个并发请求是多还是少？260s之后的响应时间为什么变长？性能瓶颈在哪里？tsung发送的请求数远远超过play的响应数，这些多出来的请求都去哪里了？

总结

从最初测试开始很长一段时间都是这样，无法确定play的最大负载能力，也不能指导程序在性能上的改进，唯一有用的可能是找到了使用nginx负载多play的时候会出现502问题。综合来说，我们缺少一种系统化的压力测试手段，通过它可以一步一步的找出play的最大负载，也应该可以解释响应时间变长的问题，指导性能优化的方向。

2.工具的选择–jmeter

最初选择jmeter是因为tsung每隔10s统计一次上一个10s内的每秒并发请求数和平均响应时间，10s对于压力测试来说太长了，若按每秒200个用户来看，10s就产生了2000个用户，或许问题就出在这10s内，google压力测试工具，jmeter相关的结果很多，教程也很多，文档齐全，最重要的是它可以记录每次请求的明细，包括请求发出的绝对时间、响应时间、返回码、是否成功、字节等，看起来很完备。jmeter是java编写的，产生不了tsung那么大的压力，在给它分配1G内存的时候，并发数达到1000的时候就不能稳定输出压力了，自己也开始做在gc。

jmeter不同于tsung，它可以配置总用户数（total_user）和在多长时间内产生这么多用户（ramptime），jmeter会根据这两个数字计算每秒应该产生多少用户，如下配置就是每秒产生30个用户——3000 / 100

jmeter测试环境

每秒响应数

这个曲线很奇怪，一个波峰接一个波峰，考虑到tsung是每10s统计一次，或许tsung也存在这个问题，只是把这些波动平均了，曲线显得平滑很多，推测可能是jmeter自己在做gc，后来对比tsung的测试结果，证实了这个推论。

响应时间

平均响应时间也很长，基本都在4秒也上，波动范围很大，看不出有用的信息。这次测试说明jmeter产生的压力远不如tsung，但也有可能play根本不需要那么大的压力就可以达到极限。

3.向前一小步

在纠结jmeter和tsung孰优孰劣的泥潭中时，偶得一神图，这幅图的意思是一个系统随着并发用户数的增多，大致可以分为三个阶段：

• 第一个阶段是light load，用户响应时间很短，且比较平衡，服务器资源利用率逐步攀升，系统吞吐量稳定增长；
• 并发用户增长到一定的量后，系统进入heavy load，服务器资源利用率达到极限，用户响应时间有所增长，系统吞吐量趋于平稳，甚至可能小幅下降；
• 并发用户数继续增长，远超系统所能承受的最大值，用户响应时间显著增长，服务器满负荷运转，系统吞吐量大幅下降（频繁的gc或缓存耗尽等影响）。

理发店模型

这个模型具有指导性的意义，一直以为我们期望找到play的最大负载能力，希望通过调整使play和服务器达到最优，但什么是最优？这个并没有标准，4000的并发是大还是小？根据这幅图的指导，我们的系统也应该有这样一张图，展示并发数与服务器资源和吞吐量的关系，有了这三个区域就可以准确的说出play的最大负载能力是多少，达到什么样的并发数必需做扩展。

压力测试的同时还要采集服务器的资源消耗情况，继续对jmeter的研究，发现了一个jmeter的插件：JMeterPluginsCMD，它可以与jmeter结合使用，在压力测试期间采集服务器的cpu使用率、内存、jvm堆变化、gc时间等参数，或许响应时间变长是因为服务器的cpu已经满负荷？内存已经接近最大？jvm在做频繁的gc？

jmeter测试环境

服务器各项性能指标

一开始不知道哪些参数有用，所以从cpu使用率，到磁盘I/O都监控了，看起来有点乱。图中比较重要的是蓝色的线，代表jvm的gc回收情况，高度是本次gc耗时，间隔越短说明gc越频繁，深红色的线是jvm heap，每次gc都会导致heap的波动。gc的效果从两方面看，一是耗时，二是heap的降幅，这幅图中heap随着gc的进行，在小范围内均匀的波动。后面会有导常的情况举例。

并发请求数

注意thinktime是10s，这条曲线堪称完美，第一次得到如此清晰的并发请求曲线，100s的时候达到最大并发数300，之后一直在300上下波动，受jmeter自己的gc的影响，曲线波动幅度稍大，整个曲线大体上左右对称。在前100s内并发请求数的增长以台阶的形式稳定爬升，每级台阶的高度是30——每秒新增用户数，宽度是10s——thinktime,100s后到达平衡区，压力稳定在300上下，500s的时候第一批产生的30个用户的50次请求已经全部完成，每隔10s就有一批用户消失，直到最终压力测试完成。

响应时间

响应时间绝大多数都是50ms以内，最高点也不过450ms。也就是这个api在这样的压力（300tps）下持续运行10分钟，完全无压力。

总结

结合服务器资源图可以看出在并发数为300的时候服务器资源利率并不高，其中cpu利用率才30%，gc回收也不频繁。在这之后的测试也都朝着这个方向走。

4.tsung+jmeter

jmeter可以非常方便的采集服务器数据，但产生的压力不够大；而tsung轻而易举的产生非常大的压力，但对服务器数据的采集不是很善长。经过讨论决定同时使用jmeter和tsung，使用tsung产生压力的同时用jmeter采集服务器数据。

tsung测试环境

总结使用jmeter测试时得到的对称曲线发现每秒产生的用户数不能太大，duration与thinktime/loop之间是有关系的，如果duration=500s，thinktime=1s，那么要保证所有的用户都产生完的时候，也就是500s的时候，第一批产生的用户还没有消失，所以此时的loop应大于等于500，用公式描述：

loop * thinktime >= duration

对称的曲线分为三部分，上升区，平稳区，下降区，其中上升区的持续时间即为duration，平稳区的持续时间是 loop * thinktime - duration；下降区是第一批产生的用户的所有请求已经成，用户数开始减少。 具体参见孙明欣写的文档

tsung产生的用户数

受限于max_user，最大用户数止于10000，在250秒的时候到达10000，此时的服务器每秒响应数为7000，此后一直在7000左右小幅波动。

每秒响应数

比较tsung产生的用户和响应的用户可以发现，在660s的时候第一幅图已经开始向了，即第一批产生的用户已经消失了，但是第二幅图中直到730s的时候才有明显的下降，这说明过多请求在play里排队。

响应时间

尽管施加了高达10000的并发，此时的play处理极限只有7000，但是用户的平均响应时间却出乎意料，最高也才500ms。

服务器性能指标

• 蓝色的线是gc回收，可以看出gc回收很频繁，其中有几根高度较高的，说明耗时稍长，是full gc
• 红色是cpu使用率,在play满负载的时候，它稳定在90%左右，考虑到我们的服务器有8个核，说明对于服务器来说远未达到最高
• 亮青色是jvm heap，随着gc上下波动，每次full gc之后都能回到原来的大小，说明没有内存泄露。

总结

这次测试确定了性能测试的基准，/v2/stest5这个api什么都没做，只是简单的返回ok，没有redis，mongodb，mysql等操作，这里只有play，所以基本可以猜测单台play在目前idc的环境下最大的负载能力是7000tps。后来有一次测试/v2/location/checkin时不小心把请求参数填错了，返回结果全是401，得到的曲线与stest5类似，这两种情况下play所做的事情都很少，证实了上述猜测。

5.步入正轨

虽然确定了play的最大负载能力，但参考理发店模型，我们相当于只找出了第一条分隔线，确定了light load和heavy load，且此时的服务器资源（cpu）并没有达到最高，后来的测试虽然给play施加了更大的压力，但是用户响应时间依然没有显著变长。此事暂且放在一边，接着测真实的api，看看真实的api与stest5有多大的差别

tsung测试环境

tsung产生的用户数

100s的时候并发用户数达到1000，此时每秒响应数曲线开始变形，系统进入heavy load区

每秒响应数

400s的时候每秒并发响应数达到最高1400

响应时间

响应时间都在800ms以下，比较奇怪的是100s的时候并发数是1000，响应时间反而比400s的时候还要长，对比服务器性能指标图，发现100s的时候服务器cpu使用率突然增长，回落后再匀速上升，而此时的gc和heap未见异常，其后又测试了几次，均未重现，考虑到测试时牵涉到其它正在使用的组件，这个异常可以忽略。

服务器性能指标

总结

由此可以确定对于locations/checkin接口来说，其最大负载能力是1400，当并发请求数到达1000的时候，系统就进入了heavy load区。

6.找出问题

下面测试sharing.index，主要是对mongodb进行了读操作

tsung测试环境

tsung产生用户数

加的压力很小，最高才每秒500个并发

每秒响应数

30s的时候曲线已经变形，而此时的压力不过150，此后的走势完全凌乱

响应时间

响应时间在30s以后一直在1s以上，最高更是达到了12s

服务器性能指标

cpu使用率达到近800%，heap的大小几乎不随gc变化，说明每次gc只回收了一点点垃圾，且全部是full gc

此时上被测的服务器上查看jvm情况，首先使用 jstat -gc 命令查看jvm各代的使用情况和gc情况，发现2G的tenured generation已经接近上限，gc没有继续进行，整个jvm处于瘫痪状态。（忘了截图了）

再使用 jmap -dump:format=b,file=/tmp/heap.hprof pid 把当前的jvm堆导出，有3G大，不过使用gzip压缩后只有400M，拉到本地使用MAT离线分析

内存泄露分析

上图MAT诊断出了两个问题，heap中存在两个超大的对象，一个814M，一个511M

问题概要

MAT认为有2个问题，第一个对象是java.util.HashMap类型的，它被system class loader加载，占据了31%的heap内存，被akka.dispatch.xxx application-xxx-dispatcher-2线程所持有；第二个问题信息较少，暂且略过。

Problem Suspect 1 detail

点击“Details >>”可以看到问题的明细，这个是当前有问题的对象到gc根的最短路径，这里gc根就是线程dispatcher-2，可以看到这个hashmap的浅引用大小是56byte深引用是536M

关于Shallow heap和Retained heap，参见MAT使用教程

聚集对象

hashmap里有很多的java.util.HashMap$Entry对象

线程明细

这样的java.util.HashMap$Entry对象有46,539个，还有当前的线程概要信息

线程调用栈

这个是当前的线程调用栈，其中的 at models.SharingStat.getCount()和at models.BaseModel.getCount()是我们自己的代码，再住上就进入了mongodb的驱动morphia里了，最终停留在java.util.hashMap.put()这里。

查看引用对象

在“Problem Suspect 1 detail”图中，最上边的java.util.HashMap$Entry上点击鼠标左键，选择“List objects” ==>“with outgoing references”可以看到它引用的对象，见下图

引用对象

注意看红框中字，这说明这个对象下引用了102,641个对象，每个对象大小是10,448byte。

很明显出现了内存泄露，把morphia的源码down下来，根据前边的线程调用情况，跟踪查看函数调用情况，最终发现问题出来我们的models.BaseModel.getCount()中有一行，

// cls is orm class,e.g. SharingStat/HotUser
BasicDAO<T, String> dao = dao(cls, ds);

每调用一次getCount()都会new一个com.google.code.morphia.dao.BaseDao,然后放到morphia中的一个hashmap中，里存储的是cls类的结构（通过反射取得），这个hashmap是全局变量，不会被gc回收，所以每次gc后heap的变化很小，jvm最后无gc，但cpu使用率还是800%，应该是这个hashmap在做resize()，hashmap不断的增大，resize()也一直继续，直到把服务器资源耗尽。

解决问题

把这个BasicDAO改成全局静态变量，只有play启动的时候初始化一次即可 下面是调整代码后的测试

tsung测试环境

tsung产生的用户数

每秒响应数

响应时间

服务器性能指标

总结

与locations/checkin类似，此api的最大负载是950，heavy load区的响应时间接近1s，稍慢，还有优化空间。

以后压力测试要改进的方向是自动化，每次修改都要进行压力测试，与之前最好的结果对比，确定不存在严重的性能问题之后才能布署上线，另外也需要增加测试专用的环境，否则会影响当前线上的服务